search

HMS-Analytical-Software / SASUnit

SASUnit is a unit testing framework for SAS(TM)-programs. It can be used for the development, execution and automatic documentation of tests for SAS programs.
GNU Lesser General Public License v3.0
2 stars 0 forks source link

[Bug]: Assert Statement followed by DATA step followed by assertLog does not log properly #36

Open Daid13 opened 2 months ago

Daid13 commented 2 months ago

Contact Details

Daniel.White@ndph.ox.ac.uk

Current Behaviour

I have a test that requires one of the datasets involved to be missing. Therefore I assert that the table doesn't exist at the start of the test, first thing after %initTestCase(). It happens this test generates a warning because both datasets are the same. However the %assertLog() does not detect it and the log for the test case looks like sasunit bug evidence1 though the log for the scenario sees it. The assertLog() claims no warnings. 

%assertTableExists(i_libref=work, i_memname=target6, i_not=1)

DATA emptySource6;
    LENGTH Sex $ 1;
    input Name $ Sex $ Age
 Height Weight;
    datalines;
;
RUN;
/*Macro call here */
%ds_copy_append ( libsrc=work, dssrc=emptySource6, libtgt=work, dstgt=target6 );

%endTestCall();

/*Asserts here */
%assertRecordCount(i_libref=work, i_memname=target6, i_recordsExp=0 )
%assertLog()

I have tried moving the assertTableExists or replacing with deleting the table. The former just includes the code up to the assertTableExists, regardless of where it is. The latter does work as a workaround though.

Expected Behaviour

%assertLog should see the whole test, regardless of whether data/macro call happens inbetween initial assert and assertLog.

Steps To Reproduce

Run something like the code snippet above, ensuring that it gives a warning and has an initial assert separate from final logging asserts.

Environment

- OS:
- SAS Version:

Release

2.1 (Default)

SASUnit Component

Assertions (Defect reports for existing assertions)

Priority / Severeness of issue

3 - moderate

Relevant log output

121
122
123        %initTestCase(i_object = &file_name, i_desc = Test empty source missing target dataset);
NOTE: 1 row was inserted into TARGET.CAS.

NOTE: PROCEDURE SQL used (Total process time):
      real time           0.00 seconds
      cpu time            0.00 seconds

27                                                                                                                       The SAS System                                                                                               13:53 Monday, July 8, 202

NOTE: PROCEDURE PRINTTO used (Total process time):
      real time           0.00 seconds
      cpu time            0.00 seconds

NOTE: PROCEDURE SQL used (Total process time):
      real time           0.00 seconds
      cpu time            0.00 seconds

NOTE: 1 row was updated in TARGET.CAS.

NOTE: PROCEDURE SQL used (Total process time):
      real time           0.00 seconds
      cpu time            0.00 seconds

NOTE: The infile "C:/Users/danielwh/Documents/Git/HSG Analysis/sas-common-testing/en/doc/testDoc/002_006.lst" is:
      Filename=C:\Users\danielwh\Documents\Git\HSG Analysis\sas-common-testing\en\doc\testDoc\002_006.lst,
      RECFM=V,LRECL=32767,File Size (bytes)=0,
      Last Modified=08Jul2024:13:53:05,
      Create Time=08Jul2024:13:53:05

NOTE: 0 records were read from the infile "C:/Users/danielwh/Documents/Git/HSG Analysis/sas-common-testing/en/doc/testDoc/002_006.lst".
NOTE: DATA statement used (Total process time):
      real time           0.00 seconds
      cpu time            0.00 seconds

NOTE: PROCEDURE SQL used (Total process time):
      real time           0.00 seconds
      cpu time            0.00 seconds

NOTE: 1 row was inserted into TARGET.TST.

NOTE: PROCEDURE SQL used (Total process time):
      real time           0.00 seconds
      cpu time            0.00 seconds

28                                                                                                                       The SAS System                                                                                               13:53 Monday, July 8, 202

========================== Check        6.1 (assertTableExists) =====================================
127        DATA emptySource6;
128            LENGTH Sex $ 1;
129            input Name $ Sex $ Age Height Weight;
130            datalines;

NOTE: The data set WORK.EMPTYSOURCE6 has 0 observations and 5 variables.
NOTE: DATA statement used (Total process time):
      real time           0.00 seconds
      cpu time            0.00 seconds

131        ;
132        RUN;
133        /*Macro call here */
134        %ds_copy_append ( libsrc=work, dssrc=emptySource6, libtgt=work, dstgt=target6 );

WARNING: IN= and OUT= are the same. Files will not be copied into themselves.
NOTE: PROCEDURE DATASETS used (Total process time):
      real time           0.00 seconds
      cpu time            0.00 seconds

NOTE: Changing the name WORK.EMPTYSOURCE6 to WORK.TARGET6 (memtype=DATA).
NOTE: PROCEDURE DATASETS used (Total process time):
      real time           0.01 seconds
      cpu time            0.00 seconds

135
136        %endTestCall();
137
138        /*Asserts here */
139        %assertRecordCount(i_libref=work, i_memname=target6, i_recordsExp=0 )

NOTE: Numeric values have been converted to character values at the places given by: (Line):(Column).
      139:1
NOTE: DATA statement used (Total process time):
      real time           0.00 seconds
      cpu time            0.00 seconds

NOTE: DATA statement used (Total process time):
      real time           0.00 seconds
      cpu time            0.00 seconds

NOTE: Table WORK._ARCTABLE created, with 0 rows and 5 columns.

29                                                                                                                       The SAS System                                                                                               13:53 Monday, July 8, 202

NOTE: PROCEDURE SQL used (Total process time):
      real time           0.01 seconds
      cpu time            0.00 seconds

NOTE: PROCEDURE SQL used (Total process time):
      real time           0.00 seconds
      cpu time            0.00 seconds

NOTE: PROCEDURE SQL used (Total process time):
      real time           0.00 seconds
      cpu time            0.00 seconds

NOTE: DATA statement used (Total process time):
      real time           0.00 seconds
      cpu time            0.00 seconds

NOTE: Libref _ARCLIB was successfully assigned as follows:
      Engine:        V9
      Physical Name: C:\Users\danielwh\Documents\Git\HSG Analysis\sas-common-testing\en\doc\tempDoc\_002_006_002_assertrecordcount
NOTE: There were 0 observations read from the data set WORK._ARCTABLE.
NOTE: The data set _ARCLIB._ARCTABLE has 0 observations and 5 variables.
NOTE: DATA statement used (Total process time):
      real time           0.01 seconds
      cpu time            0.00 seconds

NOTE: Libref _ARCLIB has been deassigned.

NOTE: Deleting WORK._ARCTABLE (memtype=DATA).
NOTE: PROCEDURE DATASETS used (Total process time):
      real time           0.00 seconds
      cpu time            0.00 seconds

NOTE: PROCEDURE SQL used (Total process time):
      real time           0.00 seconds
      cpu time            0.00 seconds

NOTE: 1 row was inserted into TARGET.TST.

NOTE: PROCEDURE SQL used (Total process time):
      real time           0.00 seconds
      cpu time            0.00 seconds

========================== Check        6.2 (assertRecordCount) =====================================
140        %assertLog()
30                                                                                                                       The SAS System                                                                                               13:53 Monday, July 8, 202

NOTE: PROCEDURE SQL used (Total process time):
      real time           0.00 seconds
      cpu time            0.00 seconds

NOTE: The infile "C:/Users/danielwh/Documents/Git/HSG Analysis/sas-common-testing/en/scn_logs/002_006.log" is:
      Filename=C:\Users\danielwh\Documents\Git\HSG Analysis\sas-common-testing\en\scn_logs\002_006.log,
      RECFM=V,LRECL=32767,File Size (bytes)=258,
      Last Modified=08Jul2024:13:53:05,
      Create Time=08Jul2024:13:53:05

NOTE: 9 records were read from the infile "C:/Users/danielwh/Documents/Git/HSG Analysis/sas-common-testing/en/scn_logs/002_006.log".
      The minimum record length was 0.
      The maximum record length was 72.
NOTE: DATA statement used (Total process time):
      real time           0.01 seconds
      cpu time            0.00 seconds

NOTE: PROCEDURE SQL used (Total process time):
      real time           0.00 seconds
      cpu time            0.00 seconds

NOTE: 1 row was inserted into TARGET.TST.

NOTE: PROCEDURE SQL used (Total process time):
      real time           0.00 seconds
      cpu time            0.00 seconds

========================== Check        6.3 (assertLog) =====================================
141
142        %endTestCase();
NOTE: PROCEDURE SQL used (Total process time):
      real time           0.00 seconds
      cpu time            0.00 seconds

NOTE: PROCEDURE SQL used (Total process time):
      real time           0.00 seconds
      cpu time            0.00 seconds

NOTE: 1 row was updated in TARGET.CAS.

NOTE: PROCEDURE SQL used (Total process time):
      real time           0.01 seconds
      cpu time            0.00 seconds

143
31
KLandwich commented 1 month ago

Hi Daniel,

I have an idea where that comes from, but need a bit time to answer.