Page 1 of 1
Strange error output using SystemTags()
Posted: Sun Feb 02, 2014 11:24 pm
by javierdlr
Hi using in DateTime.docky to launch an external program (SYS:Prefs/Time) when I click on Time prefs USE|SAVE I get a requester 'Could not open input file "ENV:Sys/time.prefs".' the launch form I'm using is:
Code: Select all
int32 beginCommand(char *command)
{
BPTR file;
if( (file = IDOS->Open("CON:0/40/640/150/DateTime.docky/AUTO", MODE_OLDFILE)) )
{
return IDOS->SystemTags(command,
SYS_Input, file,
SYS_Output, 0,
SYS_Asynch, TRUE,
SYS_UserShell, TRUE,
TAG_END);
}
return(RETURN_ERROR);
}
Changed to use (Guillame Boesel uses this way on his dockies), but get the same requester:
Code: Select all
IDOS->SystemTags("SYS:Prefs/Time", SYS_Input,NULL, SYS_Output,NULL,
SYS_Error,NULL, SYS_Asynch,TRUE, TAG_END);
Any ideas why I get such requester?
TIA
Re: Strange error output using SystemTags()
Posted: Mon Feb 03, 2014 4:36 am
by colinw
javierdlr wrote:Hi using in DateTime.docky to launch an external program (SYS:Prefs/Time)
when I click on Time prefs USE|SAVE I get a requester 'Could not open input file "ENV:Sys/time.prefs".'
Any ideas why I get such requester?
TIA
Is it a requester, or a text message in the console window you opened. ?
And, is there actually a file at; "ENV:Sys/time.prefs" ?
Re: Strange error output using SystemTags()
Posted: Mon Feb 03, 2014 10:20 am
by javierdlr
colinw wrote:javierdlr wrote:Hi using in DateTime.docky to launch an external program (SYS:Prefs/Time)
when I click on Time prefs USE|SAVE I get a requester 'Could not open input file "ENV:Sys/time.prefs".'
Any ideas why I get such requester?
TIA
Is it a requester, or a text message in the console window you opened. ?
And, is there actually a file at; "ENV:Sys/time.prefs" ?
-Is a requester, 'Preferences' (MSG_IP_REQTITLE) as window title.
-Yep, I have such file in ENV/ENVARC
-Tried with public OS4.1 update6 and i don't get such strange requester. Will try to find what happens.
EDIT: looking with Snoopy I can see that with public OS4.1 upd6:
Code: Select all
00603 : Time : o.k. = Open("Time.info",OLD) = [0x18C42F42] [84uS]
00604 : Time : CurrentDir("SYS:")
00605 : Time_Clock : o.k. = [exec] OpenDevice("timer.device",0,0x60B1BEA0,0x00000000) = 0 [40uS]
00606 : Time_Clock : o.k. = [exec] OpenDevice("timer.device",0,0x60B1BB20,0x00000000) = 0 [15uS]
00607 : Time : o.k. = [exec] OpenDevice("timer.device",0,0x60B5ED80,0x00000000) = 0 [45uS]
00608 : Time : o.k. = Open("ENV:Sys/time.prefs",NEW) = [0x18C42F42] [145uS]
00609 : « IPrefs » : o.k. = Lock("ENV:Sys/time.prefs",SHARED) [142uS]
00610 : « IPrefs » : o.k. = Examine("time.prefs") [155uS]
00611 : Time : o.k. = SetProtection("Env:Sys/time.prefs",0x00000002) [284uS]
00612 : Time : o.k. = [exec] FindPort("Time ClockPort") [13uS]
And on my beta partition (see 00143 FAIL):
Code: Select all
00137 : Time : o.k. = Open("Time.info",OLD) = [0x177C28CE] [93uS]
00138 : Time : CurrentDir("SYS:")
00139 : Time_Clock : o.k. = [exec] OpenDevice("timer.device",0,0x59F42EA0,0x00000000) = 0 [35uS]
00140 : Time_Clock : o.k. = [exec] OpenDevice("timer.device",0,0x59F42B20,0x00000000) = 0 [14uS]
00141 : Time : o.k. = [exec] OpenDevice("timer.device",0,0x59F74D80,0x00000000) = 0 [44uS]
00142 : Time : o.k. = Open("ENV:Sys/time.prefs",NEW) = [0x177C28CE] [152uS]
00143 : « IPrefs » : FAIL = Lock("ENV:Sys/time.prefs",SHARED) [86uS]
00144 : « IPrefs » : o.k. = [exec] OpenLibrary("iffparse.library",39) [20uS]
00145 : « IPrefs » : FAIL = Open("ENV:Sys/time.prefs",OLD) = [0x00000000] [74uS]
00146 : « IPrefs » : o.k. = [exec] OpenLibrary("requester.class",50) [39uS]
00147 : Time : o.k. = SetProtection("ENV:Sys/time.prefs",0x00000002) [950uS]
TIA
Re: Strange error output using SystemTags() [SOLVED?]
Posted: Mon Feb 03, 2014 6:38 pm
by javierdlr
My again. SOLVED!!!
If AmiDock icon has a NEGATIVE priority I get such problem!!!! (I had it to -10 [CX_PRIORITY=-10]) so it was launched the last one from WBStartup)
Tested with -10 and -1 ->problem!!! Requester shows up.
Tested with 0 and 1 ->no requester
Has enyone an explanation for such strange thing?
Re: Strange error output using SystemTags() [SOLVED?]
Posted: Tue Feb 04, 2014 1:50 am
by colinw
javierdlr wrote:Has enyone an explanation for such strange thing?
Looking at your log, I can see a possible race problem which the priority change could affect.
You will notice that line 142 Open()'s the file in "NEW" mode, which implies an EXCLUSIVE_LOCK,
but immediately afterwards on line 143 a SHARED_LOCK is attempted on the same file.
If the EXCLUSIVE_LOCK was not released before the SHARED_LOCK was attempted,
the SHARED_LOCK call will fail.
If you enabled UnLock() and Close() function logging, you will probably see that an asynchronous
process access caused a race condition where the Close() for the 'new' file hadn't finished before
the Lock() on line 143 was attempted.
By the way, your code is also faulty. It is possible for SystemTags() to fail with a returncode of -1
and if it does, your "file" stream never gets closed and is left orphaned forever.
Re: Strange error output using SystemTags() [SOLVED?]
Posted: Tue Feb 04, 2014 9:38 am
by javierdlr
colinw wrote:javierdlr wrote:Has enyone an explanation for such strange thing?
..
If the EXCLUSIVE_LOCK was not released before the SHARED_LOCK was attempted,
the SHARED_LOCK call will fail.
If you enabled UnLock() and Close() function logging, you will probably see that an asynchronous
process access caused a race condition where the Close() for the 'new' file hadn't finished before
the Lock() on line 143 was attempted.
By the way, your code is also faulty. It is possible for SystemTags() to fail with a returncode of -1
and if it does, your "file" stream never gets closed and is left orphaned forever.
Ok thx for explanation, setting AmiDock priority to -1 I get such snoopy log (enabling Close() function):
Code: Select all
00139 : Time_Clock : o.k. = [exec] OpenDevice("timer.device",0,0x52FECEA0,0x00000000) = 0 [35uS]
00140 : Time_Clock : o.k. = [exec] OpenDevice("timer.device",0,0x52FECB20,0x00000000) = 0 [15uS]
00141 : Time : o.k. = [exec] OpenDevice("timer.device",0,0x53008D80,0x00000000) = 0 [44uS]
00142 : Time : o.k. = Open("ENV:Sys/time.prefs",NEW) = [0x17B94CDC] [148uS]
00143 : « IPrefs » : FAIL = Lock("ENV:Sys/time.prefs",SHARED) [67uS]
00144 : « IPrefs » : o.k. = [exec] OpenLibrary("iffparse.library",39) [17uS]
00145 : « IPrefs » : FAIL = Open("ENV:Sys/time.prefs",OLD) = [0x00000000] [62uS]
00146 : « IPrefs » : o.k. = [exec] OpenLibrary("requester.class",50) [40uS]
00147 : « IPrefs » : o.k. = Lock("SYS:Prefs/Presets/Requester",SHARED) [122uS]
00148 : « IPrefs » : CurrentDir("SYS:Prefs/Presets/Requester")
00149 : « IPrefs » : o.k. = [exec] OpenLibrary("datatypes.library",44) [18uS]
00150 : « IPrefs » : o.k. = [exec] OpenLibrary("dos.library",0) [6uS]
00151 : « IPrefs » : o.k. = Lock("Error",SHARED) [37uS]
00152 : « IPrefs » : o.k. = [exec] OpenLibrary("datatypes.library",44) [10uS]
00153 : « IPrefs » : FAIL = [exec] OpenResource("PicassoIV.resource") [8uS]
00154 : « IPrefs » : CurrentDir("<ZERO>")
00155 : Time : o.k. = Close("ENV:Sys/time.prefs") [30402uS]
00156 : Time : o.k. = SetProtection("ENV:Sys/time.prefs",0x00000002) [385uS]
00157 : Time : o.k. = [exec] FindPort("Time ClockPort") [17uS]
00158 : Time_Clock : o.k. = [exec] FindPort("Time Port") [6uS]
And I see Close() now
Setting Time prefs icon priority to -1 I get the same requester.
So it's Time prefs sideeffect (bug?) for setting/"passing" a negative value to Time prefs priority?
Changed my launch command function to Guillaime Bosel "mode":
Code: Select all
int32 beginCommand(char *command)
{
return IDOS->SystemTags(command, SYS_Input,NULL, SYS_Output,NULL,
SYS_Error,NULL, SYS_Asynch,TRUE, TAG_END);
}
Re: Strange error output using SystemTags()
Posted: Tue Feb 04, 2014 4:03 pm
by salass00
@javierdir
Add "NP_Priority, 0," to the SystemTags() tags and Time prefs will always be started with priority 0 no matter what AmiDock is set to.
Re: Strange error output using SystemTags()
Posted: Tue Feb 04, 2014 6:04 pm
by javierdlr
salass00 wrote:@javierdir
Add "NP_Priority, 0," to the SystemTags() tags and Time prefs will always be started with priority 0 no matter what AmiDock is set to.
THX for the tip. Now works fine even AmiDock has Pri. -1
BTW: Should I fill a BZ entry about Time prefs and setting its icon Pri. -1 getting such "strange" requester?
Re: Strange error output using SystemTags()
Posted: Sat Feb 15, 2014 2:43 pm
by broadblues
BTW: Should I fill a BZ entry about Time prefs and setting its icon Pri. -1 getting such "strange" requester?
Looking at the log it's likely not Time Prefs that is opening the requester but IPrefs. It's likely waiting on a notification of the change to ENV:sys/time.prefs and attempting to read the changed contents. Because you were running Time prefs with a low priority IPrefs attempts to read the file before you have finished saving to it.
In StartNotify it says "For files, you will be notified after the file is closed." So this seems a bit odd. Unless it's using NotifyVar() in which I dodn't know how that works.
Re: Strange error output using SystemTags()
Posted: Sun Feb 16, 2014 1:27 am
by colinw
NotifyVar() works simply by adding hook structure nodes to a list.
When an environmental function is called that modifies a variable, like SetVar() or DeleteVar(),
the variable with the matching name has it's hook function called, and you do what you need to in there.
That's it, nice and simple and very fast, low overhead and no filesystem calls required.
Unfortunately, IPrefs still uses the filesystem style file notifications on its prefs files, and that's where
the asyncronous priority collision is likely occuring, when it gets a notification, it performs various
filesystem operations to implement the prefs change, unfortunately, the filesystem style notification
handler runs asyncronously at priority 9 or 10, and the IPrefs asyncronous handler process runs at priority 0.
The side effect of using filesystem style notifications is that you can get multiple notifications for the
one "save" operation, in that multiple filesystem calls may be involved, for example Open()-Write()-Close()
will send one notification on the Close(), but if one were to also do a SetComment(), SetProtection(),
SetDate(), while the file was still open, you would get those three change events before the Close()
event for the Write() change.
As has been documented, we are moving away from using filesystem style notifications for anything
ENV: ENVARC: related, but in this case, the way the prefs files are being changed is not entirely
consistent yet, some are still not using the propper DOS environmental functions, SetVar(), etc...
which means they would miss out on a NotifyVar() notification if they were being modified with
the old Open()-Write()->Close() method.
This will be addressed as time permits and hopefilly all the prefs files will eventually be created or
modified with the DOS environmental functions, then the problems like this should just go away.